fix: Serial Monitor corrupted output in some rare cases #1032

cmaglie · 2025-04-23T11:25:16Z

Please check if the PR fulfills these requirements

The PR has no duplicates (please search among the Pull Requests before creating one)
Tests for the changes have been added (for bug fixes / features)

What kind of change does this PR introduce?

This is a tentative fix for #1031

What is the current behavior?

The Serial Monitor may give corrupted output.

What is the new behavior?

The Serial Monitor should not show corrupted output anymore.

Does this PR introduce a breaking change?

No

Other information:

Fix #1031

codecov-commenter · 2025-04-23T11:27:16Z

Codecov Report

Attention: Patch coverage is 0% with 20 lines in your changes missing coverage. Please review.

Project coverage is 20.24%. Comparing base (87f097b) to head (fb2220f).
Report is 1 commits behind head on main.

Files with missing lines	Patch %	Lines
serialport.go	0.00%	16 Missing ⚠️
serial.go	0.00%	4 Missing ⚠️

Additional details and impacted files

@@           Coverage Diff           @@
##             main    #1032   +/-   ##
=======================================
  Coverage   20.23%   20.24%           
=======================================
  Files          42       42           
  Lines        3242     3241    -1     
=======================================
  Hits          656      656           
+ Misses       2499     2498    -1     
  Partials       87       87

Flag	Coverage Δ
unit	`20.24% <0.00%> (+<0.01%)`	⬆️

Flags with carried forward coverage won't be shown. Click here to find out more.

☔ View full report in Codecov by Sentry.
📢 Have feedback on the report? Share it here.

🚀 New features to boost your workflow:

❄️ Test Analytics: Detect flaky tests, report on failures, and find test suite problems.

per1234

I verified that the fault of the corrupted serial data (which I can reliably reproduce when using version 1.7.0 of Cloud Agent) no longer occurs when using the test build from this pull request.

However, I encounter a different fault when using the test build: sometimes when I change the baud rate, it does not take effect.

For example, this is the Cloud Agent Debug Console output that was produced when I changed the baud rate from 115200 to 9600:

[...]

{
  "P": "/dev/cu.usbserial-0001",
  "D": "Hello, world!\r\n"
}

close /dev/cu.usbserial-0001

Closing serial port /dev/cu.usbserial-0001

Shutting down reader on /dev/cu.usbserial-0001

{
  "Cmd": "Close",
  "Desc": "Got unregister/close on port.",
  "Port": "/dev/cu.usbserial-0001",
  "Baud": 115200
}

writerBuffered just got closed. make sure you make a new one. port:/dev/cu.usbserial-0001

Shutting down writer on /dev/cu.usbserial-0001

open /dev/cu.usbserial-0001 9600 timed

open /dev/cu.usbserial-0001 9600 timed

{
  "Cmd": "Open",
  "Desc": "Got register/open on port.",
  "Port": "/dev/cu.usbserial-0001",
  "Baud": 115200,
  "BufferType": "timed"
}

{
  "P": "/dev/cu.usbserial-0001",
  "D": "Hets #�\u001d@��\u0004�:��\"%=� clock div:1\r\nload:0x3fff0030,len:4888\r\nload:0x40078000,len:16516\r\nload:0x40080400,len:4\r\nload:0x40080404,len:3476\r\nentry 0x400805b4\r\n"
}

open /dev/cu.usbserial-0001 9600 timed

{
  "P": "/dev/cu.usbserial-0001",
  "D": "Hello, world!\r\n"
}

[...]

Note that the expected command was sent (though multiple times as also occurs when using 1.7.0), but the response from the Agent is:

{
  "Cmd": "Open",
  "Desc": "Got register/open on port.",
  "Port": "/dev/cu.usbserial-0001",
  "Baud": 115200,
  "BufferType": "timed"
}

(with the Baud key set to 115200 instead of 9600 as expected)

I checked 1.7.0 by changing the baud rate back and forth between 9600 and 115200 many times and this problem of the incorrect baud rate did not occur once. So it does appear to be a regression introduced by the changes proposed by this PR.

cmaglie · 2025-04-23T13:34:12Z

I've made another change @per1234, could you try the commit 5bd8910 as soon as the build is ready?

per1234

When using the build from 5bd8910, the Arduino Cloud Editor Serial Monitor fails to reconnect to the port when I change the baud rate:

Here is the debug console output from changing the baud rate from 9600 to 115200:

[...]

{
  "P": "/dev/cu.usbserial-0001",
  "D": "�"
}

{
  "P": "/dev/cu.usbserial-0001",
  "D": "�"
}

close /dev/cu.usbserial-0001

Closing serial port /dev/cu.usbserial-0001

Shutting down reader on /dev/cu.usbserial-0001

{
  "Cmd": "Close",
  "Desc": "Got unregister/close on port.",
  "Port": "/dev/cu.usbserial-0001",
  "Baud": 9600
}

Shutting down writer on /dev/cu.usbserial-0001

writerBuffered just got closed. make sure you make a new one. port:/dev/cu.usbserial-0001

open /dev/cu.usbserial-0001 115200 timed

open /dev/cu.usbserial-0001 115200 timed

{
  "Cmd": "Open",
  "Desc": "Got register/open on port.",
  "Port": "/dev/cu.usbserial-0001",
  "Baud": 115200,
  "BufferType": "timed"
}

{
  "Cmd": "OpenFail",
  "Desc": "Error opening port. Serial port busy",
  "Port": "/dev/cu.usbserial-0001",
  "Baud": 115200
}

{
  "P": "/dev/cu.usbserial-0001",
  "D": "�@1\u0012$T�tp�L&��fff0030,len:4888\r\nload:0x40078000,len:16516\r\nload:0x40080400,len:4\r\nload:0x40080404,len:3476\r\nentry 0x400805b4\r\n"
}

open /dev/cu.usbserial-0001 115200 timed

{
  "Cmd": "OpenFail",
  "Desc": "Error opening port. Serial port busy",
  "Port": "/dev/cu.usbserial-0001",
  "Baud": 115200
}

{
  "P": "/dev/cu.usbserial-0001",
  "D": "Hello, world!\r\n"
}

open /dev/cu.usbserial-0001 115200 timed

{
  "Cmd": "OpenFail",
  "Desc": "Error opening port. Serial port busy",
  "Port": "/dev/cu.usbserial-0001",
  "Baud": 115200
}

{
  "P": "/dev/cu.usbserial-0001",
  "D": "Hello, world!\r\n"
}

{
  "P": "/dev/cu.usbserial-0001",
  "D": "Hello, world!\r\n"
}

open /dev/cu.usbserial-0001 115200 timed

{
  "Cmd": "OpenFail",
  "Desc": "Error opening port. Serial port busy",
  "Port": "/dev/cu.usbserial-0001",
  "Baud": 115200
}

{
  "P": "/dev/cu.usbserial-0001",
  "D": "Hello, world!\r\n"
}

{
  "P": "/dev/cu.usbserial-0001",
  "D": "Hello, world!\r\n"
}

[...]

We can see from the output that the baud rate change was actually successful, but maybe the failures of the redundant commands cause Arduino Cloud Serial Monitor to think that the agent was not able to perform the operation?

cmaglie · 2025-04-23T16:30:33Z

We can see from the output that the baud rate change was actually successful, but maybe the failures of the redundant commands cause Arduino Cloud Serial Monitor to think that the agent was not able to perform the operation?

I think so, I changed the code again, now if a port is already opened, it will not return an error, but a success message with a "Port already opened" in the description. Let me know if this one works...

per1234

Everything is now working perfectly for me.

#1031 no longer occurs.

The two regressions that I reported in my previous reviews no longer occur.

Thanks Cristian!

lucarin91

I am wondering if it make sense to port this change also on the global client PR #1014

serialport.go

cmaglie · 2025-04-24T10:50:24Z

I am wondering if it make sense to port this change also on the global client PR #1014

We must port this change to #1014. AFAIU, even if #1014 removes the globals, it does not prevent simultaneous access to the same resource if multiple requests are coming from the websocket.

Xayton · 2025-04-24T12:14:48Z

I tried to open the same port multiple times, in a given websocket connection, and it works!

open /dev/cu.usbmodemC04E301217F82 9600

{
  "Cmd": "Open",
  "Desc": "Got register/open on port.",
  "Port": "/dev/cu.usbmodemC04E301217F82",
  "Baud": 9600,
  "BufferType": "default"
}

open /dev/cu.usbmodemC04E301217F82 9600

{
  "Cmd": "Open",
  "Desc": "Port already opened.",
  "Port": "/dev/cu.usbmodemC04E301217F82",
  "Baud": 9600,
  "BufferType": "default"
}

If I try to open the port with a different setting (like different baud rate) I will get back the same port (with the previous baud rate). I think this is fine, but it would be nice to document this new behaviour.

cmaglie · 2025-04-24T12:15:46Z

but it would be nice to document this new behaviour

where?

cmaglie · 2025-04-24T12:16:43Z

If I try to open the port with a different setting (like different baud rate) I will get back the same port (with the previous baud rate).

Maybe it should return an error in this case (when the baudrate do not match)?

Xayton · 2025-04-24T12:23:28Z

but it would be nice to document this new behaviour

where?

We could use the current documentation location (the Wiki), even if this means it's not part of the repo (and is not tracked together with other changes).

If I try to open the port with a different setting (like different baud rate) I will get back the same port (with the previous baud rate).

Maybe it should return an error in this case (when the baudrate do not match)?

Yes, we should probably return an error if the other parameters do not match (baudrate, but also the buffer algorithm).
Otherwise we have the open return a good state, but then the serial data received will be wrong/corrupted.

serialport.go

cmaglie · 2025-04-24T13:26:44Z

Yes, we should probably return an error if the other parameters do not match (baudrate, but also the buffer algorithm).
Otherwise we have the open return a good state, but then the serial data received will be wrong/corrupted

I've added a patch for this case.

Xayton

I tested the latest change and everything works:

open a port: OK (and get the list)
open again with the same baudrate: OK (no more list)
open with different parameters: fail to open

open /dev/cu.usbmodemC04E301217F82 9600

{
  "Cmd": "Open",
  "Desc": "Got register/open on port.",
  "Port": "/dev/cu.usbmodemC04E301217F82",
  "Baud": 9600,
  "BufferType": "default"
}

Serial Ports:
[
  {
    "Name": "/dev/cu.usbmodemC04E301217F82",
    "SerialNumber": "C04E301217F8",
    "IsOpen": true,
    "VendorID": "0x2341",
    "ProductID": "0x1002"
  }
]

open /dev/cu.usbmodemC04E301217F82 9600

{
  "Cmd": "Open",
  "Desc": "Port already opened.",
  "Port": "/dev/cu.usbmodemC04E301217F82",
  "Baud": 9600,
  "BufferType": "default"
}

open /dev/cu.usbmodemC04E301217F82 115200

{
  "Cmd": "OpenFail",
  "Desc": "Error opening port. Serial port busy",
  "Port": "/dev/cu.usbmodemC04E301217F82",
  "Baud": 115200
}

lucarin91 · 2025-04-24T14:34:19Z

I am wondering if it make sense to port this change also on the global client PR #1014

We must port this change to #1014. AFAIU, even if #1014 removes the globals, it does not prevent simultaneous access to the same resource if multiple requests are coming from the websocket.

yeah, but I was suggesting to do this change directly in that PR, there spHandlerOpen became a method of hub struct so we can move the mutex on that struct directly

cmaglie · 2025-04-24T14:41:48Z

yeah, but I was suggesting to do this change directly in that PR, there spHandlerOpen became a method of hub struct so we can move the mutex on that struct directly

Let's merge this PR separately, so we can do a quick release with the fix.

I'll take care to port the mutex to the proper place in the other PR (we should handle the merge conflict in any case).

Imported #1032

per1234 reviewed Apr 23, 2025

View reviewed changes

cmaglie force-pushed the multiple_opens branch from eae0887 to c2bee84 Compare April 23, 2025 13:28

Synchronize multiple open commands coming together.

5bd8910

cmaglie force-pushed the multiple_opens branch from c2bee84 to 5bd8910 Compare April 23, 2025 13:33

per1234 reviewed Apr 23, 2025

View reviewed changes

Allow re-opening of already opened ports

ac3d1f9

per1234 approved these changes Apr 23, 2025

View reviewed changes

cmaglie requested a review from a team April 24, 2025 08:08

cmaglie self-assigned this Apr 24, 2025

cmaglie added topic: code Related to content of the project itself type: imperfection Perceived defect in any part of project criticality: high Of high impact labels Apr 24, 2025

alessio-perugini approved these changes Apr 24, 2025

View reviewed changes

lucarin91 reviewed Apr 24, 2025

View reviewed changes

serialport.go Outdated Show resolved Hide resolved

Renamed mutex var and added comment

59e8c0b

cmaglie requested a review from lucarin91 April 24, 2025 10:50

cmaglie changed the title ~~Synchronize multiple open commands coming together.~~ fix: Serial Monitor corrupted output in some rare cases Apr 24, 2025

Xayton reviewed Apr 24, 2025

View reviewed changes

serialport.go Outdated Show resolved Hide resolved

Error out if baudrate and buftype of already opened port do not match

fb2220f

Xayton approved these changes Apr 24, 2025

View reviewed changes

cmaglie merged commit e7ea376 into main Apr 24, 2025
42 checks passed

cmaglie deleted the multiple_opens branch April 24, 2025 14:45

cmaglie added a commit that referenced this pull request Apr 24, 2025

Merge remote-tracking branch 'arduino/main' into remove-global-clients

1598ee1

Imported #1032

cmaglie mentioned this pull request Apr 24, 2025

Remove global clients #1014

Open

2 tasks

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

fix: Serial Monitor corrupted output in some rare cases #1032

fix: Serial Monitor corrupted output in some rare cases #1032

cmaglie commented Apr 23, 2025 •

edited

Loading

codecov-commenter commented Apr 23, 2025 •

edited

Loading

per1234 left a comment

cmaglie commented Apr 23, 2025

per1234 left a comment

cmaglie commented Apr 23, 2025

per1234 left a comment

lucarin91 left a comment

cmaglie commented Apr 24, 2025

Xayton commented Apr 24, 2025

cmaglie commented Apr 24, 2025

cmaglie commented Apr 24, 2025

Xayton commented Apr 24, 2025

cmaglie commented Apr 24, 2025

Xayton left a comment

lucarin91 commented Apr 24, 2025

cmaglie commented Apr 24, 2025

fix: Serial Monitor corrupted output in some rare cases #1032

fix: Serial Monitor corrupted output in some rare cases #1032

Conversation

cmaglie commented Apr 23, 2025 • edited Loading

codecov-commenter commented Apr 23, 2025 • edited Loading

Codecov Report

per1234 left a comment

Choose a reason for hiding this comment

cmaglie commented Apr 23, 2025

per1234 left a comment

Choose a reason for hiding this comment

cmaglie commented Apr 23, 2025

per1234 left a comment

Choose a reason for hiding this comment

lucarin91 left a comment

Choose a reason for hiding this comment

cmaglie commented Apr 24, 2025

Xayton commented Apr 24, 2025

cmaglie commented Apr 24, 2025

cmaglie commented Apr 24, 2025

Xayton commented Apr 24, 2025

cmaglie commented Apr 24, 2025

Xayton left a comment

Choose a reason for hiding this comment

lucarin91 commented Apr 24, 2025

cmaglie commented Apr 24, 2025

cmaglie commented Apr 23, 2025 •

edited

Loading

codecov-commenter commented Apr 23, 2025 •

edited

Loading